[test_pfcwd_timer_accuracy] handle exception during grep log by lipxu · Pull Request #16446 · sonic-net/sonic-mgmt

lipxu · 2025-01-10T07:23:13Z

Description of PR

Summary:
Fixes # (issue)
29970341

Type of change

Back port request

Approach

What is the motivation for this PR?

Since the test environment limitation, sometimes, pfcwd could not be triggered expectedly.
It would cause exception failure due to grep pfc watchdog syslog return failure.

How did you do it?

Handle the exception, return failure instead of raise an exception.

How did you verify/test it?

inject an failure and run the case locally.

pfcwd/test_pfcwd_timer_accuracy.py::TestPfcwdAllTimer::test_pfcwd_timer_accuracy[bjw-can-7050qx-1] 
---------------------------------------------------------------------------------------------------------------------- live log call -----------------------------------------------------------------------------------------------------------------------
05:57:06 test_pfcwd_timer_accuracy.retrieve_times L0371 WARNING| ##### Randomly skip timestamp 05:56:16.168697 parsing for pattern: [d]etected PFC storm
05:57:26 test_pfcwd_timer_accuracy.run_test       L0228 WARNING| storm_start_ms 1736488575601 or storm_detect_ms 0 or storm_end_ms 1736488588756 or storm_restore_ms 1736488589364 is 0
05:57:26 test_pfcwd_timer_accuracy.run_test       L0232 WARNING| Skip this loop due to missing timestamps
06:16:58 test_pfcwd_timer_accuracy.retrieve_times L0371 WARNING| ##### Randomly skip timestamp 06:16:07.324006 parsing for pattern: [d]etected PFC storm
06:17:17 test_pfcwd_timer_accuracy.run_test       L0228 WARNING| storm_start_ms 1736489766762 or storm_detect_ms 0 or storm_end_ms 1736489779979 or storm_restore_ms 1736489780540 is 0
06:17:17 test_pfcwd_timer_accuracy.run_test       L0232 WARNING| Skip this loop due to missing timestamps
06:20:04 test_pfcwd_timer_accuracy.retrieve_times L0371 WARNING| ##### Randomly skip timestamp 06:19:08.259521 parsing for pattern: [P]FC_STORM_END
06:20:06 test_pfcwd_timer_accuracy.run_test       L0228 WARNING| storm_start_ms 1736489935710 or storm_detect_ms 1736489936402 or storm_end_ms 0 or storm_restore_ms 1736489948823 is 0
06:20:06 test_pfcwd_timer_accuracy.run_test       L0232 WARNING| Skip this loop due to missing timestamps
06:21:30 test_pfcwd_timer_accuracy.retrieve_times L0371 WARNING| ##### Randomly skip timestamp 06:20:36.569082 parsing for pattern: [s]torm restored
06:21:30 test_pfcwd_timer_accuracy.run_test       L0228 WARNING| storm_start_ms 1736490020022 or storm_detect_ms 1736490020552 or storm_end_ms 1736490035837 or storm_restore_ms 0 is 0
06:21:30 test_pfcwd_timer_accuracy.run_test       L0232 WARNING| Skip this loop due to missing timestamps
PASSED

Any platform specific information?

Supported testbed topology if it's a new test case?

Documentation

mssonicbld · 2025-01-10T07:23:16Z

/azp run

azure-pipelines · 2025-01-10T07:23:27Z

Azure Pipelines successfully started running 1 pipeline(s).

StormLiangMS

LGTM

mssonicbld · 2025-01-13T07:21:38Z

@lipxu PR conflicts with 202405 branch

mssonicbld · 2025-01-13T07:21:39Z

@lipxu PR conflicts with 202411 branch

lipxu · 2025-01-13T09:05:06Z

202405
#16490

lipxu · 2025-01-13T09:06:49Z

202411
#16491

… grep log #16490 What is the motivation for this PR? #16446 merged PR to 202405 conflict How did you do it? manually merge

auspham · 2025-02-02T23:45:01Z

tests/pfcwd/test_pfcwd_timer_accuracy.py

+
+            # Regular expressions for the two timestamp formats
+            regex1 = re.compile(r'^[A-Za-z]{3} \d{2} \d{2}:\d{2}:\d{2}\.\d{6}')
+            regex2 = re.compile(r'^\d{4} [A-Za-z]{3} \d{2} \d{2}:\d{2}:\d{2}\.\d{6}')


@lipxu is there any reasons why we're switching to regex here?

Sorry, @auspham , just saw the comments. sorry for the late response.
I used regex here because I initially aimed to standardize the handling function by searching for the timestamp and processing it with the same function, however, during UT test, I found the date command does not support the format with the year. therefore, I reverted to the previous handling process but retained the regex change here. thanks.

Maybe we can only search the timestamp without year, let me try

Description of PR Summary: Fixes # (issue) 31202914 From #16446 we are changing to use regex to capture the timestamp for pfc timer accuracy. However, the regex does not cover the scenario where date digit is 1. For example: 2025 Jan 5 00:53:14.103188 Approach What is the motivation for this PR? Comparing between: 2025 Jan 26 17:36:31.27789 2025 Feb 2 15:17:24.055182 We can see that we might need up to 2 spaces after month and the number of day digits can vary between 1 to 2. How did you do it? Adjust the regex so it matches for both format How did you verify/test it? image Signed-off-by: Austin Pham <austinpham@microsoft.com>

Description of PR Summary: Fixes # (issue) 31202914 From sonic-net#16446 we are changing to use regex to capture the timestamp for pfc timer accuracy. However, the regex does not cover the scenario where date digit is 1. For example: 2025 Jan 5 00:53:14.103188 Approach What is the motivation for this PR? Comparing between: 2025 Jan 26 17:36:31.27789 2025 Feb 2 15:17:24.055182 We can see that we might need up to 2 spaces after month and the number of day digits can vary between 1 to 2. How did you do it? Adjust the regex so it matches for both format How did you verify/test it? image Signed-off-by: Austin Pham <austinpham@microsoft.com>

Description of PR Summary: Fixes # (issue) 31202914 From #16446 we are changing to use regex to capture the timestamp for pfc timer accuracy. However, the regex does not cover the scenario where date digit is 1. For example: 2025 Jan 5 00:53:14.103188 Approach What is the motivation for this PR? Comparing between: 2025 Jan 26 17:36:31.27789 2025 Feb 2 15:17:24.055182 We can see that we might need up to 2 spaces after month and the number of day digits can vary between 1 to 2. How did you do it? Adjust the regex so it matches for both format How did you verify/test it? image Signed-off-by: Austin Pham <austinpham@microsoft.com>

bingwang-ms · 2025-02-08T00:59:23Z

@lipxu We saw the error below recently. Can you help check if the error is caused by this change?

        err_msg = ("Real detection time is greater than configured: Real detect time: {} "
>                  "Expected: {} (wd_detect_time + wd_poll_time)".format(self.all_detect_time[check_point],
                                                                         config_detect_time))
E       IndexError: list index out of range

Description of PR Summary: Fixes # (issue) 31202914 From sonic-net#16446 we are changing to use regex to capture the timestamp for pfc timer accuracy. However, the regex does not cover the scenario where date digit is 1. For example: 2025 Jan 5 00:53:14.103188 Approach What is the motivation for this PR? Comparing between: 2025 Jan 26 17:36:31.27789 2025 Feb 2 15:17:24.055182 We can see that we might need up to 2 spaces after month and the number of day digits can vary between 1 to 2. How did you do it? Adjust the regex so it matches for both format How did you verify/test it? image Signed-off-by: Austin Pham <austinpham@microsoft.com>

Description of PR Summary: Fixes # (issue) 31202914 From #16446 we are changing to use regex to capture the timestamp for pfc timer accuracy. However, the regex does not cover the scenario where date digit is 1. For example: 2025 Jan 5 00:53:14.103188 Approach What is the motivation for this PR? Comparing between: 2025 Jan 26 17:36:31.27789 2025 Feb 2 15:17:24.055182 We can see that we might need up to 2 spaces after month and the number of day digits can vary between 1 to 2. How did you do it? Adjust the regex so it matches for both format How did you verify/test it? image Signed-off-by: Austin Pham <austinpham@microsoft.com>

lipxu · 2025-02-11T05:21:57Z

@lipxu We saw the error below recently. Can you help check if the error is caused by this change?

        err_msg = ("Real detection time is greater than configured: Real detect time: {} "
>                  "Expected: {} (wd_detect_time + wd_poll_time)".format(self.all_detect_time[check_point],
                                                                         config_detect_time))
E       IndexError: list index out of range

Hi， @bingwang-ms ， Yes， should be related to the timestamp parser, it fixed by the PR #16757, please let me know if we still hit the issue with this fix, thanks

### Description of PR  Summary: Fixes # (issue) 31202914 From sonic-net#16446 we are changing to use regex to capture the timestamp for pfc timer accuracy. However, the regex does not cover the scenario where date digit is 1. For example: `2025 Jan 5 00:53:14.103188 ` ### Type of change  - [ ] Bug fix - [ ] Testbed and Framework(new/improvement) - [ ] New Test case - [ ] Skipped for non-supported platforms - [ ] Test case improvement ### Back port request - [ ] 202012 - [ ] 202205 - [ ] 202305 - [ ] 202311 - [ ] 202405 - [ ] 202411 ### Approach #### What is the motivation for this PR? Comparing between: - `2025 Jan 26 17:36:31.27789` - `2025 Feb 2 15:17:24.055182` We can see that we might need up to 2 spaces after month and the number of day digits can vary between 1 to 2. #### How did you do it? Adjust the regex so it matches for both format #### How did you verify/test it? ![image](https://github.com/user-attachments/assets/31a72bdd-bed8-4b01-80d9-fc2e8366ac2c) #### Any platform specific information? #### Supported testbed topology if it's a new test case? ### Documentation

…et#16446) What is the motivation for this PR? Since the test environment limitation, sometimes, pfcwd could not be triggered expectedly. It would cause exception failure due to grep pfc watchdog syslog return failure. How did you do it? Handle the exception, return failure instead of raise an exception. How did you verify/test it? inject an failure and run the case locally. pfcwd/test_pfcwd_timer_accuracy.py::TestPfcwdAllTimer::test_pfcwd_timer_accuracy[bjw-can-7050qx-1] ---------------------------------------------------------------------------------------------------------------------- live log call ----------------------------------------------------------------------------------------------------------------------- 05:57:06 test_pfcwd_timer_accuracy.retrieve_times L0371 WARNING| ##### Randomly skip timestamp 05:56:16.168697 parsing for pattern: [d]etected PFC storm 05:57:26 test_pfcwd_timer_accuracy.run_test L0228 WARNING| storm_start_ms 1736488575601 or storm_detect_ms 0 or storm_end_ms 1736488588756 or storm_restore_ms 1736488589364 is 0 05:57:26 test_pfcwd_timer_accuracy.run_test L0232 WARNING| Skip this loop due to missing timestamps 06:16:58 test_pfcwd_timer_accuracy.retrieve_times L0371 WARNING| ##### Randomly skip timestamp 06:16:07.324006 parsing for pattern: [d]etected PFC storm 06:17:17 test_pfcwd_timer_accuracy.run_test L0228 WARNING| storm_start_ms 1736489766762 or storm_detect_ms 0 or storm_end_ms 1736489779979 or storm_restore_ms 1736489780540 is 0 06:17:17 test_pfcwd_timer_accuracy.run_test L0232 WARNING| Skip this loop due to missing timestamps 06:20:04 test_pfcwd_timer_accuracy.retrieve_times L0371 WARNING| ##### Randomly skip timestamp 06:19:08.259521 parsing for pattern: [P]FC_STORM_END 06:20:06 test_pfcwd_timer_accuracy.run_test L0228 WARNING| storm_start_ms 1736489935710 or storm_detect_ms 1736489936402 or storm_end_ms 0 or storm_restore_ms 1736489948823 is 0 06:20:06 test_pfcwd_timer_accuracy.run_test L0232 WARNING| Skip this loop due to missing timestamps 06:21:30 test_pfcwd_timer_accuracy.retrieve_times L0371 WARNING| ##### Randomly skip timestamp 06:20:36.569082 parsing for pattern: [s]torm restored 06:21:30 test_pfcwd_timer_accuracy.run_test L0228 WARNING| storm_start_ms 1736490020022 or storm_detect_ms 1736490020552 or storm_end_ms 1736490035837 or storm_restore_ms 0 is 0 06:21:30 test_pfcwd_timer_accuracy.run_test L0232 WARNING| Skip this loop due to missing timestamps PASSED Any platform specific information?

Description of PR Summary: Fixes # (issue) 31202914 From sonic-net#16446 we are changing to use regex to capture the timestamp for pfc timer accuracy. However, the regex does not cover the scenario where date digit is 1. For example: 2025 Jan 5 00:53:14.103188 Approach What is the motivation for this PR? Comparing between: 2025 Jan 26 17:36:31.27789 2025 Feb 2 15:17:24.055182 We can see that we might need up to 2 spaces after month and the number of day digits can vary between 1 to 2. How did you do it? Adjust the regex so it matches for both format How did you verify/test it? image Signed-off-by: Austin Pham <austinpham@microsoft.com>

handle exception during grep log

2546b62

lipxu requested review from StormLiangMS and cyw233 January 10, 2025 07:23

StormLiangMS approved these changes Jan 13, 2025

View reviewed changes

StormLiangMS merged commit 7440e89 into sonic-net:master Jan 13, 2025

StormLiangMS added Request for 202405 branch Request for 202411 branch Approved for 202405 branch Approved for 202411 branch labels Jan 13, 2025

mssonicbld added the Cherry Pick Conflict_202405 label Jan 13, 2025

mssonicbld added the Cherry Pick Conflict_202411 label Jan 13, 2025

lipxu mentioned this pull request Jan 13, 2025

[202405] backport PR 16446 [test_pfcwd_timer_accuracy] handle exception during grep log #16490

Merged

12 tasks

StormLiangMS pushed a commit that referenced this pull request Jan 15, 2025

backport PR 16446 [test_pfcwd_timer_accuracy] handle exception during…

aac72d5

… grep log #16490 What is the motivation for this PR? #16446 merged PR to 202405 conflict How did you do it? manually merge

lipxu added Included in 202405 branch Included in 202411 branch and removed Cherry Pick Conflict_202405 Cherry Pick Conflict_202411 labels Jan 15, 2025

auspham reviewed Feb 2, 2025

View reviewed changes

auspham mentioned this pull request Feb 2, 2025

fix: pfc timer accuracy timestamp regex #16757

Merged

11 tasks

mssonicbld mentioned this pull request Feb 3, 2025

[action] [PR:16757] fix: pfc timer accuracy timestamp regex #16763

Merged

11 tasks

mssonicbld mentioned this pull request Feb 11, 2025

[action] [PR:16757] fix: pfc timer accuracy timestamp regex #16890

Merged

11 tasks

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

[test_pfcwd_timer_accuracy] handle exception during grep log#16446

[test_pfcwd_timer_accuracy] handle exception during grep log#16446
StormLiangMS merged 1 commit intosonic-net:masterfrom
lipxu:20250110_public_pfcwd_accuracy

lipxu commented Jan 10, 2025

Uh oh!

mssonicbld commented Jan 10, 2025

Uh oh!

azure-pipelines bot commented Jan 10, 2025

Uh oh!

StormLiangMS left a comment

Uh oh!

mssonicbld commented Jan 13, 2025

Uh oh!

mssonicbld commented Jan 13, 2025

Uh oh!

lipxu commented Jan 13, 2025

Uh oh!

lipxu commented Jan 13, 2025

Uh oh!

auspham Feb 2, 2025

Uh oh!

lipxu Feb 11, 2025

Uh oh!

lipxu Feb 11, 2025

Uh oh!

bingwang-ms commented Feb 8, 2025

Uh oh!

lipxu commented Feb 11, 2025

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

5 participants

Conversation

lipxu commented Jan 10, 2025

Description of PR

Type of change

Back port request

Approach

What is the motivation for this PR?

How did you do it?

How did you verify/test it?

Any platform specific information?

Supported testbed topology if it's a new test case?

Documentation

Uh oh!

mssonicbld commented Jan 10, 2025

Uh oh!

azure-pipelines bot commented Jan 10, 2025

Uh oh!

StormLiangMS left a comment

Choose a reason for hiding this comment

Uh oh!

mssonicbld commented Jan 13, 2025

Uh oh!

mssonicbld commented Jan 13, 2025

Uh oh!

lipxu commented Jan 13, 2025

Uh oh!

lipxu commented Jan 13, 2025

Uh oh!

auspham Feb 2, 2025

Choose a reason for hiding this comment

Uh oh!

lipxu Feb 11, 2025

Choose a reason for hiding this comment

Uh oh!

lipxu Feb 11, 2025

Choose a reason for hiding this comment

Uh oh!

bingwang-ms commented Feb 8, 2025

Uh oh!

lipxu commented Feb 11, 2025

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

5 participants